fix: emit a single "event" key when the event-name tag collides with a user key#132
Merged
Merged
Conversation
…user key LoggingEvent.log() always emitted the structured event-name tag under the reserved "event" key whenever event(name) was called, with no de-duplication against the other key sources (global context, MDC, per-event field). Because SLF4J's addKeyValue appends rather than replaces, a "event" key supplied by the global context, the folded MDC, or a field(...) produced a second KeyValuePair with the same name, which JSON appenders serialise as invalid duplicate-key JSON. The event-name tag is now authoritative for the "event" key: when a non-empty name is set, any "event" key from the global context, MDC, or a per-event field is suppressed so the event carries the key exactly once. When no name is set, a user-supplied "event" key passes through unchanged. The three folding loops in log() are extracted into small private helpers, which keeps the method under the cyclomatic-complexity threshold and removes the multi-jump loop bodies.
OmarAlJarrah
changed the title
Member
Author
|
Fixes a real duplicate-key bug: when I verified the suppression only triggers when a name tag is actually set (the over-suppression guard test confirms a user |
When event(name) sets the authoritative event-name tag, a per-event
field("event", ...) collides with the reserved EVENT_KEY and its value is
dropped so the tag stays the single "event" entry. That drop was silent.
Surface it at DEBUG via a small warnOnDroppedEventField helper, so the
override is visible while debugging without adding noise on the normal path:
DEBUG is off by default, and only the explicit field() collision is flagged
(ambient "event" keys from the global context or MDC defer to the tag
silently, as before). The disabled-path cost is a single containsKey check.
Also thread the already-read globalContext and mdcKeys into emitMdc instead
of re-reading them off the logger.
…gger
The DEBUG hint emitted when a per-event field("event", …) collides with the
authoritative event(name) tag fired on every log() call, so a misuse sitting in
a hot loop flooded DEBUG with the same line. The collision is a static call-site
error, so a single line per logger is enough to surface it.
The once-guard lives on ClientLogger because LoggingEvent is single-shot, so the
"already warned" state has to outlive it: a CAS-gated AtomicBoolean, checked after
isDebugEnabled so the guard is spent only on an actual emission and a level enabled
later at runtime still warns once. Adds a regression test asserting the diagnostic
fires at most once across repeated collisions on one logger.
warnOnDroppedEventField probed the per-event field map on every log() call that set an event-name tag, including when DEBUG was off and the diagnostic it guards could never be emitted. Front the probe with the DEBUG-level check so the containsKey lookup is skipped on that hot path; the once-per-logger throttle still re-checks the level before spending its guard, so behaviour is unchanged.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Problem
LoggingEvent.log()always emitted the structured event-name tag under the reserved"event"key whenever.event(name)was called with a non-empty name, with no de-duplication against the other key sources (the logger's global context, the folded MDC, and per-eventfield(...)). SLF4J'saddKeyValueappends rather than replaces, so a"event"key supplied by any of those sources produced a secondKeyValuePairwith the same name on the event, which JSON appenders serialise as invalid duplicate-key JSON.Reproduction:
This emitted two
evententries. The same happened when the logger's global context or the MDC carried an"event"key.Change
The event-name tag is now authoritative for the
"event"key. When a non-empty name is set, any"event"key arriving from the global context, the folded MDC, or a per-eventfield(...)is suppressed, so the event carries the"event"key exactly once with the name tag's value. When no name is set (or it was cleared), a user-supplied"event"key passes through unchanged as an ordinary field.This extends the same single-emission guarantee already in place for the global-context / MDC / field sources to the event-name code path.
The three folding loops in
log()are extracted into small private helpers (emitGlobalContext,emitMdc,emitFields), which keeps the method under the cyclomatic-complexity threshold and removes the multi-jump loop bodies.Tests
Added regression tests in
LoggingEventTest, alongside the existing "emitted exactly once" tests, covering the name-tag collision with a per-event field, with a global-context key, and with an MDC key, plus a guard that a user"event"field still passes through when no name tag is set.Gated build
Ran scoped (no daemon):
Result: BUILD SUCCESSFUL. No public-API change, so no
apiDumpwas required.Closes #116